[q] We calculate the ticks before vm.runTry() or vm.run()where ticks is ticking(vm.r.ticks++). Would it return 0 in some case? Correct me. I may be lost somewhere.
[q] can we add some tests to see if we're able to get the ticks metrics correctly?e.g. creating a vm to run a function and return this metrics. It may be not easy because we need to know the expected ticks(lol).

For some background I had a previous iteration of this that tracked ticks at the exec call but that came with a ~20-30% performance hit.

		} else {
                         // tick tracking occurred here
			vm.prg.code[vm.pc].exec(vm)
		}

[q] We calculate the ticks before vm.runTry() or vm.run()where ticks is ticking(vm.r.ticks++). Would it return 0 in some case? Correct me. I may be lost somewhere.

Yes there may be some scenarios on initial setup where this gets hit and no new ticks have been calculated yet. I think for the run and runTry scenario you are referencing it would probably get handled by the existing vm.prg being nil (i.e. this check in setPrg if vm.prg != nil {)

I like your idea to add tests, I originally compared the setPrg solution against the results of the verbose solution I referenced above and did not see any discrepancies, but I'll add a few tests to solidify that check.

[q1] yes, I believe in some cases the ticks could be 0, but I believe that's fine. I'll let Calvin confirm that thought :)

[q2] agreed. Now that we're closer to a solution we should start adding some tests. We don't need to check exact ticks, but we should make sure that the metrics contain the correct functions and that the ticks of an expensive JS function are higher than the ticks of trivial functions. It might also be worth testing that executing a function X times generates X times more ticks than executing the same function once.

[q1] yes, I believe in some cases the ticks could be 0, but I believe that's fine. I'll let Calvin confirm that thought :)

[q2] agreed. Now that we're closer to a solution we should start adding some tests. We don't need to check exact ticks, but we should make sure that the metrics contain the correct functions and that the ticks of an expensive JS function are higher than the ticks of trivial functions. It might also be worth testing that executing a function X times generates X times more ticks than executing the same function once.

What I mean by the situation of returning 0 is when vm.prg != nil. In an extreme case, in the very beginning, vm.r.Ticks() should return 0 because ticks is not ticking yet. vm.lastFunctionTicks is also 0. So line 328 will plus 0 at that time.

Yeah I think that edge case is ok.

I say that because I think I prefer the noop (adding 0) over the logic it would take to avoid that scenario.

Let me know if you disagree though!

I also think this is fine, but @LijieZhang1998 let me know if you disagree/if I'm misunderstanding your comment. We don't care too much about these metrics being 100% accurate. We just want to figure out which are the top 10 or so functions we should be focusing on improving.

I was going to make this map get initialized per the functionTickTrackingEnabled setting but this actual would cause a problem (as demonstrated by the test). We need to have the vm object in order to enable the tick tracking but we also check if it is enabled when we create the vm object. So I think its better to just always initialize this map.

			vm := New()
			if tc.functionTickTrackingEnabled {
				vm.EnableFunctionTickTracking()
			}

(^ snippet from the unit test)

[opt] I would document this in code

[opt] similar comment here about dropping the word "Function". Also, thoughts on grouping all the new tick functions together? i.e. move the TickMetrics down here.

So the only reason I left "Function" here is "EnableTickTracking" sounds like it is for the main tick counter i.e. vm.r.ticks++... However we could do something like "EnableTickMetricTracking"

I agree on grouping these functions together. I'll do that.

I also think this is fine, but @LijieZhang1998 let me know if you disagree/if I'm misunderstanding your comment. We don't care too much about these metrics being 100% accurate. We just want to figure out which are the top 10 or so functions we should be focusing on improving.

[mega-nit] function names could have an underscore. Thoughts on going with a period instead?

The only reason I went with a _ is because the prg.src.Name() can be a file name so test.js.functionName looked a bit weird. I can go back to the period though, I don't have a strong opinion on this.

do we need this?

No I'll remove, this is leftover from changing all of the vm.prg sets to use the setPrg function.

[q] could we call vm.profileTicks() within vm.pushCtx()?

I think that's a great idea! This handles a majority of the scenarios. There was a scenario that I left the vm.profileTicks() call but I'll comment on it after I push.

[nit] let's flip this check and return early instead. That'll reduce indentation and improve the readability of this function. i.e.

if !vm.r.functionTickTrackingEnabled {
  return
}

these tests will break fairly easily if we compare the exact ticks. We don't really care about the tick values. We just want to make sure that the values are reasonable when compared to one another.

I'll just check to make sure that the keys line up and the values are greater than 0

[q1]can we add some more tests such as executing executing class functions and multiple nested functions?

[q2] Also, do you mind sharing the metrics that we would generate from baas when using a dependency such as the aws sdk? The easiest way to do this might be to run our dependencies tests in evergreen with the tracking enabled.

[q1]can we add some more tests such as executing executing class functions and multiple nested functions?

Yeah absolutely!

[q2] Also, do you mind sharing the metrics that we would generate from baas when using a dependency such as the aws sdk? The easiest way to do this might be to run our dependencies tests in evergreen with the tracking enabled.

Would that data be in splunk? Or would we need to parse the output of the tests?

Evergreen task with tick metric tracking hardcoded to true. Will update this thread with the results.

Sounds good. I'm curious to see if the current approach makes it easy enough for us to identify which function is consuming the most amount of this. Let me know when this is ready.

Hmm for some reason the logs aren't showing the "tick metrics" logs for that evergreen run.

I think my local testing might alleviate some of your concerns though.

exports = async function(arg){
  const { Buffer } = require('buffer');
  const loremIpsumText = // long string
  return Buffer.from(loremIpsumText);
};

[Note that the tickMetricsToLog array is sorted so we are looking at the top 5 tick contributors]

The majority of usage for this Buffer.from example is BufferJS::utf8ToBytes and BufferJS::blitBuffer.

I'll also callout that these tick metrics are flat (not cumulative) in that we are measuring the specific time only for that function.

So in this case we would know that we would want to have a native implementation in Go for utf8ToBytes and probably blitBuffer as well, which is nice because this allows us to not have to potentially waste time porting over the entire Buffer.from implementation.

Hmm for some reason the logs aren't showing the "tick metrics" logs for that evergreen run.

I have a feeling this is happening because of how tick metrics are aggregated and published asynchronously. It doesn't even look like the cmd/server/main.go executes which is where this asynchronous logic would start.

I went ahead and set this up manually though, here are the results when running against aws-sdk-v3/s3

hmac lol

oh nice work, hello mr Buffer not surprised to see you up there!

Without this we would miss the ticks tracked for the above vm.runTry

	ex := vm.runTry(r.vm.ctx)
	if ex == nil {
		result = r.vm.result
	} else {
		err = ex
	}
	if recursive {
		vm.popCtx()
		vm.halt = false
		vm.clearStack()
	} else {
		vm.stack = nil
		vm.profileTicks()
		vm.prg = nil
		vm.setFuncName("")
		r.leave()
	}

It could turn out that this isn't necessary because it is captured by the pushCtx/restoreCtx, but I don't think it hurts to have this in place just to make sure we capturing any lingering ticks for the program. Worst case scenario is there are no new ticks and we add 0 for the program.

If we think this clutters the code I can dig more into this and see if it is necessary.

Yeah without this we would miss a few ticks in a few edge cases, not the end of the world but probably nice to keep around.

Keeping it works for me.

Keeping it works for me.

should we add a comment for these exported functions?

[opt] Continuing this thread here.
ah good point... Yeah I don't have a strong opinion either. Maybe we can go with ::?

Ooo I really like :: thanks!!

Sounds good. I'm curious to see if the current approach makes it easy enough for us to identify which function is consuming the most amount of this. Let me know when this is ready.

[opt] I would document this in code

[nit] The one test I'm missing here is a function that throws an error. I was playing around with popCtx vs restoreCtx and most of the times profiling from either yields the same results. The only exception was when I was using it inside of the restoreCtx (like you are in this PR) where I noticed different ticks values when my function was throwing an error. Just thought it would be useful to have that case here. Realistically it will pass the test anyway and we won't see much different but profiling from popCtx only was missing out on some ticks.

Good point! I added a test to cover that we track ticks for a function that errors. 👍